Logging improvements #3157

kolyshkin · 2021-08-12T18:17:43Z

This makes runc --debug logs more readable, along with some refactoring and logs tests improvements (originally part of #3114).

init.go, main.go: don't use logs.ConfigureLogging
libct/logs: remove ConfigureLogging
Improve libct/logs and its tests
libct/logs: test: make more robust
libct/logs: parse log level implicitly
libct/logs: do not show caller in nsexec logs
runc --debug: shorter caller info

The biggest user-facing change is how debug logs are more clean / less cluttered:

$ runc --debug run x
ERRO[0000]github.com/opencontainers/runc/utils.go:61 main.fatalWithCode() JSON specification file config.json not found

$ runc --debug run -d x
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[2360844]: => nsexec container setup   
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[2360844]: update /proc/self/oom_score_adj to '30' 
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec-0[2360844]: ~> nsexec stage-0         
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec-0[2360844]: spawn stage-1             
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec-0[2360844]: -> stage-1 synchronisation loop 
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec-1[2360846]: ~> nsexec stage-1         
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec-1[2360846]: unshare remaining namespace (except cgroupns) 
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec-1[2360846]: spawn stage-2             
DEBU[0000]github.com/opencontainers/runc/libcontainer/logs/logs.go:69 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec-1[2360846]: request stage-0 to forward stage-2 pid (2360848)

After:

$ runc --debug run x
ERRO[0000]utils.go:61 main.fatalWithCode() JSON specification file config.json not found

$ runc --debug run -d x
DEBU[0000] nsexec[2359952]: => nsexec container setup   
DEBU[0000] nsexec[2359952]: update /proc/self/oom_score_adj to '30' 
DEBU[0000] nsexec-0[2359952]: ~> nsexec stage-0         
DEBU[0000] nsexec-0[2359952]: spawn stage-1             
DEBU[0000] nsexec-0[2359952]: -> stage-1 synchronisation loop 
DEBU[0000] nsexec-1[2359954]: ~> nsexec stage-1         
DEBU[0000] nsexec-1[2359954]: unshare remaining namespace (except cgroupns) 
DEBU[0000] nsexec-1[2359954]: spawn stage-2             
DEBU[0000] nsexec-1[2359954]: request stage-0 to forward stage-2 pid (2359955) 
...

Fixes: #3183
Fixes: #3184

thaJeztah · 2021-08-17T13:41:05Z

init.go

 		if err != nil {
 			panic(fmt.Sprintf("libcontainer: failed to convert environment variable _LIBCONTAINER_LOGPIPE=%s to int: %s", logPipeFdStr, err))
 		}
-		err = logs.ConfigureLogging(logs.Config{


Perhaps the original intent was to try to abstract away logrus, to allow swapping with something else, but given that we already import logrus here, I agree that it doesn't add anything really useful.

It actually makes things worse because

its two users have different needs;

its existence makes the intention of libcontainer/logs package blurry (since the removal it's now clear that this it's about forwarding logs from runc init to the parent process).

init.go

thaJeztah · 2021-08-17T13:44:14Z

init.go

 		if err != nil {
 			panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err))
 		}
+		logrus.SetLevel(logLevel)


Slightly tempted to move this together with the other ones (even though it's further away from where logLevel is set, the logLevel variable is descriptive enough IMO)

Same thing in _LIBCONTAINER_LOGPIPE parsing (a few lines below -- github won't let me comment) -- strconv.Atoi error already contains the value which it was unable to convert, so no need for intermediate logPipeFdStr.

init.go

main.go

libcontainer/logs/logs_linux_test.go

kolyshkin · 2021-08-17T18:13:34Z

Thanks for review @thaJeztah, I implemented most of the suggested changes are explained the one that I did not ("the case of missing curly braces"). Also rebased and fixed a couple of commit message typos. PTAL

thaJeztah

LGTM

one it in the first commit, but no show-stopper

main.go

libcontainer/logs/logs.go

thaJeztah · 2021-08-20T13:40:38Z

We should consider if Logrus is still the best solution for us. It provides many features, somewhat nearing "feature-creep". It's also in "maintenance mode" mostly. I know there's more lightweight solutions (if performance matters), but haven't looked closely at them to see if they're useful.

This function is somewhat strange and I always wanted to remove it, as it tries to satisfy both init.go and main.go, which have somewhat different needs. It is more straightforward and readable to configure logrus directly. While at it, simplify errors on panic (errors from logrus.ParseLevel and strconv.Atoi already contain value which they fail to parse, and panic already contains enough context to figure out what's wrong). Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin · 2021-08-20T18:02:01Z

We should consider if Logrus is still the best solution for us. It provides many features, somewhat nearing "feature-creep". It's also in "maintenance mode" mostly. I know there's more lightweight solutions (if performance matters), but haven't looked closely at them to see if they're useful.

Yes, I feel the same way (also about some other packaged used here, e.g. urlfave/cli).

I guess that's a separate topic though.

Previous commits removed all its users -- the only one left is package's own unit tests. Modify those unit tests to configure logrus directly, and remove ConfigureLogging for good. The world is better without it. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin · 2021-08-20T18:02:58Z

Fixed the fmt var in the first commit; PTAL @thaJeztah

thaJeztah

still LGTM, thanks!

kolyshkin · 2021-09-03T17:51:38Z

init.go

+		logLevel, err := logrus.ParseLevel(os.Getenv("_LIBCONTAINER_LOGLEVEL"))
 		if err != nil {
-			panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err))
+			panic(err)


The error message from logrus.ParseLevel is descriptive enough, no need to wrap it.

libcontainer/logs/logs_linux_test.go

When playing with the log forwarder, I broke it, but all the units tests were still passing. This happened because test cases were merely looking for a word (like "kitten") in the log output, which also happened to be there in case of an error (as a part of an error message produced by log forwarder). Make the test a bit more robust by - looking for a complete log message, not just part of it; - also checking that log file does NOT contain errors. Signed-off-by: Kir Kolyshkin <[email protected]>

There's no need to call logrus.ParseLevel as logrus.Level already implements encoding.TextUnmarshaler interface. Signed-off-by: Kir Kolyshkin <[email protected]>

Commit 9f3d753 enabled logrus to show information about log caller, if --debug is set. It is helpful in many scenarios, but does not work very well when we are debugging runc init, for example: # runc --debug run -d xx4557 DEBU[0000]libcontainer/logs/logs.go:45 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[279687]: logging set up DEBU[0000]libcontainer/logs/logs.go:45 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[279687]: logging set up DEBU[0000]libcontainer/logs/logs.go:45 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[279687]: => nsexec container setup DEBU[0000]libcontainer/logs/logs.go:45 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[279687]: update /proc/self/oom_score_adj to '30' As we're merely forwarding the logs here, printing out filename:line and function is useless and clutters the logs a log. To fix, create and use a copy of the standard logger with caller info turned off. With this in place, nsexec logs are sane again: # runc --debug --log-format=text run -d xe34 DEBU[0000] nsexec[293595]: logging set up DEBU[0000] nsexec[293595]: logging set up DEBU[0000] nsexec[293595]: => nsexec container setup DEBU[0000] nsexec[293595]: update /proc/self/oom_score_adj to '30' This patch also changes Logf to Log in processEntry, as this is what it should be. Signed-off-by: Kir Kolyshkin <[email protected]>

Commit 9f3d753 enabled logrus to show information about log caller, if --debug is set. The problem is, the file name and in many cases the function name have a long prefix of github.com/opencontainers/runc (this is with -trimpath, and without it it's worse). Add a function to trim the prefix. Note all this happens only when --debug is given. Signed-off-by: Kir Kolyshkin <[email protected]>

thaJeztah

LGTM

kolyshkin · 2021-09-07T03:19:49Z

I have #3201 which needs this PR; @opencontainers/runc-maintainers PTAL

cyphar

LGTM.

kolyshkin mentioned this pull request Aug 12, 2021

[DNM] runc init log refactor #3114

Closed

3 tasks

kolyshkin requested review from AkihiroSuda, cyphar and thaJeztah August 13, 2021 00:54

thaJeztah reviewed Aug 17, 2021

View reviewed changes

kolyshkin force-pushed the logs-cleanup branch from 3a11520 to 3143d7f Compare August 17, 2021 18:08

kolyshkin requested a review from thaJeztah August 17, 2021 18:13

kolyshkin added the area/logging label Aug 19, 2021

thaJeztah previously approved these changes Aug 20, 2021

View reviewed changes

main.go Outdated Show resolved Hide resolved

libcontainer/logs/logs.go Show resolved Hide resolved

kolyshkin dismissed thaJeztah’s stale review via 45eca78 August 20, 2021 18:02

kolyshkin force-pushed the logs-cleanup branch from 3143d7f to 45eca78 Compare August 20, 2021 18:02

kolyshkin requested a review from thaJeztah August 20, 2021 18:03

thaJeztah previously approved these changes Aug 20, 2021

View reviewed changes

kolyshkin added the kind/refactor refactoring label Aug 26, 2021

kolyshkin added this to the 1.1.0 milestone Aug 31, 2021

kolyshkin commented Sep 3, 2021

View reviewed changes

tjucoder reviewed Sep 4, 2021

View reviewed changes

libcontainer/logs/logs_linux_test.go Outdated Show resolved Hide resolved

kolyshkin added 4 commits September 4, 2021 11:47

libct/logs: parse log level implicitly

c3910e7

There's no need to call logrus.ParseLevel as logrus.Level already implements encoding.TextUnmarshaler interface. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin dismissed thaJeztah’s stale review via a20c8b2 September 4, 2021 18:48

kolyshkin force-pushed the logs-cleanup branch from 45eca78 to a20c8b2 Compare September 4, 2021 18:48

kolyshkin requested a review from thaJeztah September 4, 2021 18:48

thaJeztah approved these changes Sep 6, 2021

View reviewed changes

kolyshkin mentioned this pull request Sep 7, 2021

nsexec.c: don't write logs that are to be discarded #3201

Merged

cyphar approved these changes Sep 9, 2021

View reviewed changes

cyphar merged commit 3eccbe9 into opencontainers:master Sep 9, 2021

Logging improvements #3157

Logging improvements #3157

Uh oh!

Conversation

kolyshkin commented Aug 12, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah Aug 17, 2021

Choose a reason for hiding this comment

Uh oh!

kolyshkin Aug 17, 2021

Choose a reason for hiding this comment

Uh oh!

Uh oh!

thaJeztah Aug 17, 2021

Choose a reason for hiding this comment

Uh oh!

kolyshkin Aug 17, 2021

Choose a reason for hiding this comment

Uh oh!

kolyshkin Aug 17, 2021

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

kolyshkin commented Aug 17, 2021

Uh oh!

thaJeztah left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

thaJeztah commented Aug 20, 2021

Uh oh!

kolyshkin commented Aug 20, 2021

Uh oh!

kolyshkin commented Aug 20, 2021

Uh oh!

thaJeztah left a comment

Choose a reason for hiding this comment

Uh oh!

kolyshkin Sep 3, 2021

Choose a reason for hiding this comment

Uh oh!

Uh oh!

thaJeztah left a comment

Choose a reason for hiding this comment

Uh oh!

kolyshkin commented Sep 7, 2021

Uh oh!

cyphar left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

kolyshkin commented Aug 12, 2021 •

edited

Loading